From dev-return-13373-apmail-karaf-dev-archive=karaf.apache.org@karaf.apache.org Thu Jan 17 17:34:10 2019 Return-Path: X-Original-To: apmail-karaf-dev-archive@minotaur.apache.org Delivered-To: apmail-karaf-dev-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 0F79C108A0 for ; Thu, 17 Jan 2019 17:34:10 +0000 (UTC) Received: (qmail 57610 invoked by uid 500); 17 Jan 2019 17:34:09 -0000 Delivered-To: apmail-karaf-dev-archive@karaf.apache.org Received: (qmail 57577 invoked by uid 500); 17 Jan 2019 17:34:09 -0000 Mailing-List: contact dev-help@karaf.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@karaf.apache.org Delivered-To: mailing list dev@karaf.apache.org Received: (qmail 57556 invoked by uid 99); 17 Jan 2019 17:34:09 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 17 Jan 2019 17:34:09 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id C02BAC26AB for ; Thu, 17 Jan 2019 17:34:08 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 1.798 X-Spam-Level: * X-Spam-Status: No, score=1.798 tagged_above=-999 required=6.31 tests=[DKIMWL_WL_MED=-0.001, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, HTML_MESSAGE=2, RCVD_IN_DNSWL_NONE=-0.0001, SPF_PASS=-0.001] autolearn=disabled Authentication-Results: spamd4-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id qKHr5cY3BIRK for ; Thu, 17 Jan 2019 17:34:06 +0000 (UTC) Received: from mail-lf1-f54.google.com (mail-lf1-f54.google.com [209.85.167.54]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTPS id 594206110B for ; Thu, 17 Jan 2019 17:08:35 +0000 (UTC) Received: by mail-lf1-f54.google.com with SMTP id n18so8369616lfh.6 for ; Thu, 17 Jan 2019 09:08:35 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to; bh=3JAWtNFT8KcoXZJflFgFqt2GmJYtn9jB11lIWv4Aj9A=; b=eZg/9noo58CSBLuaddtv+3r3sZ9Dm8dK1KEZOr8OyBgZNraNoiyZN8lu53YyOOOPwX bJBf3zn93k9TgEy0MwUqEcWPC2uOwocca2OyegGd5ngai+mlbdwUWdEGK0sXpBi/iZp8 BF+iqy7mGquPxxkLmZCU3AbF1TdO5qS23p9qX0YY7SGeM2mHdQq4WA6HcziqUUOL/kG/ qIxJYHeH/9yvmb4JNuOrw5rBn0PwovDAefQl6hCRudO1k86THMTPr0qF+M3msGm1Htt9 qVGN0paVJOxWYMEoox+FYpS9ZZ+FNMphED7CY2zoozb5rijSoFQCTiOF7IYdI1OefArH pFOg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to; bh=3JAWtNFT8KcoXZJflFgFqt2GmJYtn9jB11lIWv4Aj9A=; b=YrA+oYvZtTxBkhqX0WEPCdccPVwikG/Efnm+aVReZcf2qw1SP6wm4NQ5JXImAj79Rx N8TQG2b59YNgAJxv1Yw+u+nVBi4KesRjaRtD+J8cTA2g+h6KqgRyV9mHBmtbOVofTZl6 yv8krpI57RLj+KqnLdbJSUnt6d6wxKDPuTmJqCyKS/m9gOKpa/XdHSowC9PydW5ALI8v 541bmF8sxD0uTdrkeP2VDWY9dfi/BlGuB1HWmDLP9pJlqRyw+k22GWuIPoKxgZUehlx9 Vo1ee8mRIBYIZK3hBXledzRwCSAnR/6gPHEH6ezjqlrorQYsng5xzqQ9qDtpoAcwYuT4 UMyA== X-Gm-Message-State: AJcUukf7+D8UmOe7m+HbLTpUFa43fsvtKZ3N2TiLhabAK8eE3SAFLHo8 xE4gFaYdN0Jri4g8tcaSQlIen+7dhOaIQE6jopX5dbCp X-Google-Smtp-Source: ALg8bN6dugjNqd8G+4Gw1vjCSVGWLw7XZ4Q2HaX8zwF9gSDUQ6WpEK6oZ5E5D0Kk+eNNu9a59z1iTLMmOR5TqvCE1bE= X-Received: by 2002:a19:2106:: with SMTP id h6mr10595312lfh.29.1547744908314; Thu, 17 Jan 2019 09:08:28 -0800 (PST) MIME-Version: 1.0 References: <162d9e32-1c0a-3f0e-b6c4-4e1810bb2068@nanthrax.net> In-Reply-To: From: Grzegorz Grzybek Date: Thu, 17 Jan 2019 18:08:16 +0100 Message-ID: Subject: Re: SCR Bundle refreshes Pax Logging? To: dev@karaf.apache.org Content-Type: multipart/alternative; boundary="0000000000007692b3057faa71f9" --0000000000007692b3057faa71f9 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable You don't have to find the source of WTF :) pax-logging-log4j2 has: Import-Package: org.apache.commons.csv;resolution:=3Doptional regards Grzegorz Grzybek czw., 17 sty 2019 o 17:07 Fabian Lange napisa=C5= =82(a): > Hi, > see its not a karaf problem. > Grzegorz gave me really good hints off-list, and it turns out I do > load a feature which contains this apache commons bundle: > > mvn:org.apache.commons/commons-csv/1.5 > > after I remove this bundle, the logging classes are no longer loaded twic= e. > Now the next step is to find out WTF, but I leave that for another day > > Fabian > > On Thu, Jan 17, 2019 at 3:49 PM Grzegorz Grzybek > wrote: > > > > Hello > > > > I suggest checking jansi - you have SL=3D8 for jansi bundle and SL=3D7 = for > > pax-logging-log4j2. > > > > pax-logging-log4j has optional import for org.fusesource.jansi - and th= is > > may be the cause of refresh. > > > > In my custom distro, my etc/startup.properties has: > > > > mvn\:org.fusesource.jansi/jansi/1.17 =3D 8 > > mvn\:org.ops4j.pax.logging/pax-logging-api/1.10.1 =3D 8 > > mvn\:org.ops4j.pax.logging/pax-logging-log4j2/1.10.1 =3D 8 > > > > So I've already ensured that jansi starts/resolves before > > pax-logging-log4j2. > > > > I hope this helps. > > > > regards > > Grzegorz Grzybek > > > > czw., 17 sty 2019 o 15:15 Jean-Baptiste Onofr=C3=A9 > napisa=C5=82(a): > > > > > Not a problem, Jira should be used when we "suspect" something. I thi= nk > > > it's good for the tracking and also for the history of faced problems= . > > > > > > Just my =E2=82=AC0.01 ;) > > > > > > Regards > > > JB > > > > > > On 17/01/2019 15:12, Fabian Lange wrote: > > > > I already feel bad for asking such wide questions here. I usually > only > > > > file tickets once I kind-of know whats going on. > > > > Could be a Felix or SCR issue as well ;) > > > > > > > > Fabian > > > > > > > > On Thu, Jan 17, 2019 at 3:10 PM Jean-Baptiste Onofr=C3=A9 < > jb@nanthrax.net> > > > wrote: > > > >> > > > >> Hi Fabian, > > > >> > > > >> did you create a Jira about that ? It's for the tracking as I'm > > > >> preparing Karaf 4.2.3 ;) > > > >> > > > >> Thanks ! > > > >> Regards > > > >> JB > > > >> > > > >> On 17/01/2019 15:08, Fabian Lange wrote: > > > >>> Quick update, this apparently is still the case with Karaf 4.2.2 > > > >>> > > > >>> Would appreciate if somebody knows a workaround. I am able to pla= y > > > >>> around with startlevels, but I cant seem to avoid this. > > > >>> > > > >>> Fabian > > > >>> > > > >>> On Mon, Nov 26, 2018 at 1:21 AM Fabian Lange < > lange.fabian@gmail.com> > > > wrote: > > > >>>> > > > >>>> Hi, > > > >>>> currently debugging an issue. Maybe the bits I came up so far ar= e > > > >>>> already sufficient for you guys to fix it, or you help me how to > debug > > > >>>> this better. > > > >>>> In our distribution, we have these features > > > >>>> > > > >>>> 0 =E2=94=82 Active =E2=94=82 0 =E2=94=82 5.6.10 =E2= =94=82 System Bundle, Fragments: 1 > > > >>>> 1 =E2=94=82 Resolved =E2=94=82 1 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Features :: > > > >>>> Extension, Hosts: 0 > > > >>>> 2 =E2=94=82 Active =E2=94=82 5 =E2=94=82 2.5.4 =E2= =94=82 OPS4J Pax Url - aether: > > > >>>> 3 =E2=94=82 Active =E2=94=82 7 =E2=94=82 1.10.1 =E2= =94=82 OPS4J Pax Logging - Log4j v2 > > > >>>> 4 =E2=94=82 Active =E2=94=82 7 =E2=94=82 1.10.1 =E2= =94=82 OPS4J Pax Logging - API > > > >>>> 5 =E2=94=82 Active =E2=94=82 8 =E2=94=82 1.17.1 =E2= =94=82 jansi > > > >>>> 6 =E2=94=82 Active =E2=94=82 9 =E2=94=82 1.0.2 =E2= =94=82 Apache Felix Coordinator > Service > > > >>>> 7 =E2=94=82 Active =E2=94=82 10 =E2=94=82 1.9.4 =E2= =94=82 Apache Felix Configuration > > > Admin Service > > > >>>> 8 =E2=94=82 Active =E2=94=82 11 =E2=94=82 3.6.4 =E2= =94=82 Apache Felix File Install > > > >>>> 9 =E2=94=82 Active =E2=94=82 15 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Features :: > Core > > > >>>> 10 =E2=94=82 Active =E2=94=82 20 =E2=94=82 2.2.11.1 =E2= =94=82 Apache ServiceMix :: > Bundles :: > > > jaxb-impl > > > >>>> 11 =E2=94=82 Active =E2=94=82 30 =E2=94=82 1.2.0 =E2= =94=82 Apache Felix Metatype > Service > > > >>>> 12 =E2=94=82 Active =E2=94=82 30 =E2=94=82 2.1.2 =E2= =94=82 Apache Felix Declarative > > > Services > > > >>>> 13 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Bundle :: > Core > > > >>>> 14 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: ConfigAdmin > :: > > > Core > > > >>>> 15 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Features :: > > > Command > > > >>>> 16 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Log :: Core > > > >>>> 17 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: SCR :: > Bundle > > > State > > > >>>> 18 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Service :: > Core > > > >>>> 19 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Shell :: > > > Various Commands > > > >>>> 20 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: Shell :: > Core > > > >>>> 21 =E2=94=82 Active =E2=94=82 30 =E2=94=82 4.2.1 =E2= =94=82 Apache Karaf :: System :: > Core > > > >>>> 22 =E2=94=82 Active =E2=94=82 30 =E2=94=82 3.9.0 =E2= =94=82 JLine Builtins > > > >>>> 23 =E2=94=82 Active =E2=94=82 30 =E2=94=82 3.9.0 =E2= =94=82 JLine Reader > > > >>>> 24 =E2=94=82 Active =E2=94=82 30 =E2=94=82 3.9.0 =E2= =94=82 JLine Terminal, Fragments: > 25 > > > >>>> 25 =E2=94=82 Resolved =E2=94=82 30 =E2=94=82 3.9.0 =E2= =94=82 JLine JANSI Terminal, > Hosts: 24 > > > >>>> > > > >>>> What I noticed is that A LOT of apache LOG4J classes are loaded > twice > > > >>>> in the JVM. > > > >>>> I turned on -verbose:class and saw this snippet: > > > >>>> > > > >>>> [5.580s][info][class,load] > > > >>>> org.apache.felix.scr.impl.logger.StdOutLogger source: > > > >>>> jar:bundle://12.0:0/!/ > > > >>>> [5.626s][info][class,load] > > > >>>> org.apache.felix.framework.util.ImmutableMap$1 source: > > > >>>> > > > > file:/Users/fabian/work/karaf-dist/system/org/apache/felix/org.apache.fel= ix.framework/5.6.10/org.apache.felix.framework-5.6.10.jar > > > >>>> [5.834s][info][class,load] > > > >>>> > > > > org.apache.karaf.features.internal.service.BundleInstallSupportImpl$$Lamb= da$412/0x00000007fecd0c40 > > > >>>> source: > > > org.apache.karaf.features.internal.service.BundleInstallSupportImpl > > > >>>> [5.834s][info][class,load] > > > >>>> org.apache.felix.framework.Felix$RefreshHelper source: > > > >>>> > > > > file:/Users/fabian/work/karaf-dist/system/org/apache/felix/org.apache.fel= ix.framework/5.6.10/org.apache.felix.framework-5.6.10.jar > > > >>>> [5.970s][info][class,load] > > > >>>> org.ops4j.pax.logging.log4j2.internal.Activator source: > > > >>>> jar:bundle://3.0:0/!/ > > > >>>> > > > >>>> So here is my suspicion: Whatever SCR does, it causes the Log4j2 > > > >>>> bundle to reload all classes and activate again. This leads to a= ll > > > >>>> bundles before the SCR to reference the first loaded log4j > classes, > > > >>>> and all afterwards the refreshed bundle. > > > >>>> > > > >>>> Can we prevent this somehow? Also curiously SCR uses its > StdOutLogger, > > > >>>> which it shouldnt do. > > > >>>> Is this reload caused by the Service Tracker > > > >>>> org.apache.felix.scr.impl.logger.LogServiceEnabledLogger uses? > > > >>>> > > > >>>> Ideas, suggestions how to prevent this refresh? I played with th= e > load > > > >>>> order but it does not seem possible to get it right > > > >>>> > > > >>>> Fabian > > > >> > > > >> -- > > > >> Jean-Baptiste Onofr=C3=A9 > > > >> jbonofre@apache.org > > > >> http://blog.nanthrax.net > > > >> Talend - http://www.talend.com > > > > > > -- > > > Jean-Baptiste Onofr=C3=A9 > > > jbonofre@apache.org > > > http://blog.nanthrax.net > > > Talend - http://www.talend.com > > > > --0000000000007692b3057faa71f9--