Skip to content
This repository has been archived by the owner on Jun 1, 2023. It is now read-only.

Xposed on lollipop does not write to application log #34

Closed
Falseclock opened this issue Apr 6, 2015 · 61 comments
Closed

Xposed on lollipop does not write to application log #34

Falseclock opened this issue Apr 6, 2015 · 61 comments
Labels
bug

Comments

@Falseclock
Copy link 

public class XMain implements IXposedHookInitPackageResources, IXposedHookLoadPackage
{
    @Override
    public void handleLoadPackage(LoadPackageParam lpparam) throws Throwable
    {
        XposedBridge.log("-------------handleLoadPackage");
    }

    @Override
    public void handleInitPackageResources(InitPackageResourcesParam resparam) throws Throwable
    {
        XposedBridge.log("-------------handleInitPackageResources");
    }
}

I do not see any debug or exception log from Xposed under application menu except logs coming from initZygote.
But this log can be found in logcat. Unfortunately logcat contains only last 10k lines, so I'm not able see any exceptions or debug information after phone full restart.
how to solve this issue?
@rovo89
Copy link
Owner

rovo89 commented Apr 7, 2015

I cannot reproduce this, the lines are written to the log that can be seen in the installer app. Are you sure that your module is loaded correctly? Can you add an initZygote() method with the same logging and then post your log file?

@rovo89
Copy link
Owner

rovo89 commented Apr 7, 2015

Besides that, please use the XposedBridge repository the next time, this repo is for the native part...

@Falseclock
Copy link
Author 

package kz.virtex.htc.tweaker.lollipop;

import de.robv.android.xposed.IXposedHookInitPackageResources;
import de.robv.android.xposed.IXposedHookLoadPackage;
import de.robv.android.xposed.IXposedHookZygoteInit;
import de.robv.android.xposed.XposedBridge;
import de.robv.android.xposed.callbacks.XC_InitPackageResources.InitPackageResourcesParam;
import de.robv.android.xposed.callbacks.XC_LoadPackage.LoadPackageParam;

public class XMain implements IXposedHookZygoteInit, IXposedHookInitPackageResources, IXposedHookLoadPackage
{
    @Override
    public void handleLoadPackage(LoadPackageParam paramLoadPackageParam) throws Throwable
    {
        XposedBridge.log("-------------handleLoadPackage: " + paramLoadPackageParam.packageName);
    }

    @Override
    public void handleInitPackageResources(InitPackageResourcesParam resparam) throws Throwable
    {
        XposedBridge.log("-------------handleInitPackageResources: " + resparam.packageName);
    }

    @Override
    public void initZygote(StartupParam startupParam) throws Throwable
    {
        XposedBridge.log("-------------initZygote");
    }
}

Log from application:

04-08 00:03:44.173 I/Xposed  (11488): -----------------
04-08 00:03:44.173 I/Xposed  (11488): Starting Xposed binary version 61, compiled for SDK 21
04-08 00:03:44.173 I/Xposed  (11488): Device: HTC One dual sim (HTC), Android version 5.0.2 (SDK 21)
04-08 00:03:44.173 I/Xposed  (11488): ROM: LRX22G release-keys
04-08 00:03:44.173 I/Xposed  (11488): Build fingerprint: htc/htc_europe/m7cdug:5.0.2/LRX22G/499633.5:user/release-keys
04-08 00:03:44.173 I/Xposed  (11488): Platform: armeabi-v7a, 32-bit binary, system server: yes
04-08 00:03:44.173 I/Xposed  (11488): SELinux enabled: yes, enforcing: yes
04-08 00:03:45.204 I/Xposed  (11488): -----------------
04-08 00:03:45.204 I/Xposed  (11488): Added Xposed (/system/framework/XposedBridge.jar) to CLASSPATH
04-08 00:03:45.274 I/Xposed  (11488): Detected ART runtime
04-08 00:03:45.284 I/Xposed  (11488): Found Xposed class de/robv/android/xposed/XposedBridge, now initializing
04-08 00:03:45.504 I/Xposed  (11488): Initializing XposedBridge version 62
04-08 00:03:45.584 I/Xposed  (11488): Loading modules from /data/app/kz.virtex.htc.tweaker.lollipop-1/base.apk
04-08 00:03:45.694 I/Xposed  (11488):   Loading class kz.virtex.htc.tweaker.lollipop.XMain
04-08 00:03:45.694 I/Xposed  (11488): -------------initZygote
04-08 00:03:45.694 I/Xposed  (11488): Loading modules from /data/app/com.sensetoolbox.six-2/base.apk
04-08 00:03:45.774 I/Xposed  (11488):   Loading class com.sensetoolbox.six.mods.XMain

Logcat:
https://drive.google.com/file/d/0B5l6hlK799AFb1NMRGNBZ1NlYlE/view?usp=sharing

@rovo89
Copy link
Owner

rovo89 commented Apr 7, 2015

Very strange... As I mentioned, this is not a general issue, it's working fine for me. I don't know what could cause this, just two thoughts:

  • Is there a native process called "xposed_logcat" running? It's responsible for writing the log to the file.
  • If you check the file on the file system (/data/data/de.robv.android.xposed.installer/log/error.log), is it more complete?

@rovo89 rovo89 added the bug label Apr 7, 2015
@Falseclock
Copy link
Author 

shell@m7cdug:/ $ cat /data/data/de.robv.android.xposed.installer/log/error.log
a/data/de.robv.android.xposed.installer/log/error.log                         <
04-08 00:03:44.173 I/Xposed  (11488): -----------------
04-08 00:03:44.173 I/Xposed  (11488): Starting Xposed binary version 61, compiled for SDK 21
04-08 00:03:44.173 I/Xposed  (11488): Device: HTC One dual sim (HTC), Android version 5.0.2 (SDK 21)
04-08 00:03:44.173 I/Xposed  (11488): ROM: LRX22G release-keys
04-08 00:03:44.173 I/Xposed  (11488): Build fingerprint: htc/htc_europe/m7cdug:5.0.2/LRX22G/499633.5:user/release-keys
04-08 00:03:44.173 I/Xposed  (11488): Platform: armeabi-v7a, 32-bit binary, system server: yes
04-08 00:03:44.173 I/Xposed  (11488): SELinux enabled: yes, enforcing: yes
04-08 00:03:45.204 I/Xposed  (11488): -----------------
04-08 00:03:45.204 I/Xposed  (11488): Added Xposed (/system/framework/XposedBridge.jar) to CLASSPATH
04-08 00:03:45.274 I/Xposed  (11488): Detected ART runtime
04-08 00:03:45.284 I/Xposed  (11488): Found Xposed class de/robv/android/xposed/XposedBridge, now initializing
04-08 00:03:45.504 I/Xposed  (11488): Initializing XposedBridge version 62
04-08 00:03:45.584 I/Xposed  (11488): Loading modules from /data/app/kz.virtex.htc.tweaker.lollipop-1/base.apk
04-08 00:03:45.694 I/Xposed  (11488):   Loading class kz.virtex.htc.tweaker.lollipop.XMain
04-08 00:03:45.694 I/Xposed  (11488): -------------initZygote
04-08 00:03:45.694 I/Xposed  (11488): Loading modules from /data/app/com.sensetoolbox.six-2/base.apk
04-08 00:03:45.774 I/Xposed  (11488):   Loading class com.sensetoolbox.six.mods.XMain

1|shell@m7cdug:/ $ ps|grep xposed
ps|grep xposed
root      11517 11488 32716  1808  ffffffff 00000000 S xposed_service_system
root      11518 11488 33744  1808  ffffffff 00000000 S xposed_service_app
root      11519 11516 29612  1632  ffffffff 00000000 S xposed_logcat
u0_a304   16943 11488 1640360 73152 ffffffff 00000000 S de.robv.android.xposed.installer
shell@m7cdug:/ $

@Falseclock Falseclock reopened this Apr 7, 2015
@rovo89
Copy link
Owner

rovo89 commented Apr 7, 2015

Hm. Really strange. You can check the source code yourself: https://github.com/rovo89/Xposed/blob/master/xposed_logcat.cpp#L83
It must be in the loop, otherwise the process would be gone. `foundMarker´ is true, as some lines have been logged. So there are only three possibilities:

  • It's hanging while reading from the logcat command (maybe that one has crashed or is not delivering new output?).
  • The line starts with a dash - but that would be an invalid read, it worked fine with the initZygote line.
  • It's hanging while writing to the file.

@Falseclock
Copy link
Author

you know, when android sends broadcast boot complete, i can issue adb logcat command, but after a couple of seconds command ends and I have to give adb logcat again.

do xposed_logcat handles such scenarios in case of logcat restart?

@Falseclock
Copy link
Author

is it strange or normal behavior?

ps|grep logcat
root      407   404   1112   592   ffffffff 00000000 S logcat
root      11516 11488 1112   596   ffffffff 00000000 S logcat
root      11519 11516 29612  1632  ffffffff 00000000 S xposed_logcat
shell@m7cdug:/ $

@rovo89
Copy link
Owner

rovo89 commented Apr 7, 2015

It doesn't restart logcat, and it shouldn't need to... logcat should keep running all the time. It displays the output line by line as they are logged, so the buffer size should be a limiting factor. Actually, once logcat ends, xposed_logcat should end as well.

I don't know what the first logcat command is about, but the second one seems to be the one started by Xposed.

So It seems that the logcat command on your device is somehow buggy... what if you start adb shell logcat instead?

@Falseclock
Copy link
Author

this happens before disconnect
but xposed log still empty

W/libprocessgroup(  840): failed to open /acct/uid_10087/pid_5183/cgroup.procs: No such file or directory
I/Xposed  ( 5434): -------------handleLoadPackage: com.htc.demoflopackageinstaller
I/Xposed  ( 5434): -------------handleInitPackageResources: com.htc.demoflopackageinstaller
D/DFPI.PIReciver( 5434): onReceiver action:android.intent.action.MEDIA_SCANNER_FINISHED
I/DFPI.ApkInstallService( 5434): onHandleIntent
I/DFPI.ApkInstallService( 5434): Media Scan Finished Case
D/DFPI.ApkInstallService( 5434): check CID = HTC__001
I/DFPI.ApkInstallService( 5434): There is no Demo.apk in sd card or phone storage
D/PMS     (  840): acquireWL(527d2d9): PARTIAL_WAKE_LOCK  NlpWakeLock 0x1 2015 10024 null
D/PMS     (  840): releaseWL(527d2d9): PARTIAL_WAKE_LOCK  NlpWakeLock 0x1 null
D/GCM     ( 1649): GcmService start Intent { act=com.google.android.gms.INITIALIZE flg=0x10 pkg=com.google.android.gms cmp=com.google.android.gms/.gcm.GcmService } com.google.andro
id.gms.INITIALIZE
D/AuthorizationBluetoothService( 1649): Received GmsCore event: Intent { act=com.google.android.gms.INITIALIZE flg=0x10 pkg=com.google.android.gms cmp=com.google.android.gms/.auth.
be.proximity.authorization.bt.AuthorizationBluetoothService$AutoStarter }.
D/c       ( 1649): Getting all permits...
D/a       ( 1649): Opening database...
D/a       ( 1649): Opening database auth.proximity.permit_store...
D/a       ( 1649): Closing database...
V/GmsCoreStatsServiceLauncher( 2153): Received broadcast intent Intent { act=com.google.android.gms.INITIALIZE flg=0x10 pkg=com.google.android.gms cmp=com.google.android.gms/.commo
n.stats.GmsCoreStatsServiceLauncher }
E/MDM     ( 2015): [187] b.run: Couldn't connect to Google API client: ConnectionResult{statusCode=API_UNAVAILABLE, resolution=null}
D/LocationInitializer( 2153): Restart initialization of location
I/Xposed  ( 5375): -------------handleInitPackageResources: com.buak.Link2SD
I/art     ( 2611): Debugger is no longer active
I/WSP     ( 1189): [Receiver] EVENT - CURRENT LOCATION CHANGED
D/MtpReceiver( 2375): [MTP][handleUsbStateAsync]+
D/MtpReceiver( 2375): [MTP][handleUsbStateAsync]1:1-
D/MtpReceiver( 2375): [MTP][handleUsbState]+
D/CDMountReceiver( 5130): receive action: com.htc.intent.action.USB_CONNECT2PC  connected :true
D/CDMountReceiver( 5130): USB connected to PC
D/MtpReceiver( 2375): [MTP][scanExternalVolumeIfNeed] scan external volume
D/MtpReceiver( 2375): [MTP][handleUsbState]-
D/MtpReceiver( 2375): [MTP][handleMessage]-
D/PMS     (  840): acquireWL(bbddc38): PARTIAL_WAKE_LOCK  wake:com.google.android.gms/com.google.android.libraries.social.mediamonitor.MediaMonitorIntentService 0x1 2153 10024 null

D/MtpService( 2375): updating state; isCurrentUser=true, mMtpLocked=false
D/MtpDatabase( 2375): TotalSize=1857004,MediaCacheLimit=6000
D/Atlas   ( 5375): Validating map...
D/FOTAReceiver( 5130): onReceive() enter
D/FOTAReceiver( 5130): receive action: com.htc.intent.action.USB_CONNECT2PC  connected :true
D/MtpService( 2375): [isMtpConnected] connected: true
D/TetherSettings( 5356): CustomizedNS:true CustomizedML:false CustomizedSPCSC:false CustomizedIPT:true CustomizedSingleUSBfalse
D/        ( 5356): Cust_ConnectToPC   : Internet_Sharing>true
D/        ( 5356): Cust_ConnectToPC   : Modem_Link>false
D/        ( 5356): Cust_ConnectToPC   : spcsc>false
D/        ( 5356): Cust_ConnectToPC   : IPT>true
D/        ( 5356): Cust_ConnectToPC   : Singel_USB>false
W/Settings( 5356): Setting tethering_blocked has moved from android.provider.Settings.Secure to android.provider.Settings.Global.
E/SmartNS_Utility( 5356): hasRemovableStorageSlot: true
D/SmartNS_Utility( 5356): [ACC]Settings-Wireless_+_network-USB_tethering_:usb_storage_notification=false
D/SmartNS_NSReceiver( 5356): onReceive : com.htc.intent.action.USB_CONNECT2PC hasTethered:false isNSOpening:false
D/SmartNS_Utility( 5356): usb_cable_connect = 1
D/SmartNS_Utility( 5356): usb_denied = 0
D/MediaProvider( 2375): [resizeThumb] thumbnail original width 500, height 500
D/MediaProvider( 2375): [resizeThumb] thumbnail 1st resize width 500, height 500, mAlbumSize=512
I/SmartNS_NSReceiver( 5356): locked:falsesecurity:falseisLocked:false
D/SmartNS_NSReceiver( 5356): USB = true hasTethered = false isNSOpening: false
I/PSReceiver( 5356): onReceive:com.htc.intent.action.USB_CONNECT2PC
W/ContextImpl( 5356): Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1824 android.content.ContextWrapper.startService:515 and
roid.content.ContextWrapper.startService:515 com.android.settings.PSReceiver.onReceive:36 android.app.ActivityThread.handleReceiver:2712
I/SmartNS_PSService( 5356): onReceive:com.htc.intent.action.USB_CONNECT2PC
W/Settings( 5356): Setting tethering_blocked has moved from android.provider.Settings.Secure to android.provider.Settings.Global.
I/SmartNS_PSService( 5356):  defaultType:1
I/SmartNS_PSService( 5356): fail notificaiton:false
D/SmartNS_Utility( 5356): usb_cable_connect = 1
D/SmartNS_Utility( 5356): usb_denied = 0
I/SmartNS_PSService( 5356): usb notificaiton:true
E/WifiStateMachine(  840): WiFiDisplay: getWifidisplayApEnabled=false
I/ActivityManager(  840): Start proc com.htc.calendar for broadcast com.htc.calendar/.ProviderChangeReceiver: pid=5465 uid=10071 gids={50071, 9997, 3003, 1028, 1015, 1023} abi=arme
abi-v7a
I/iu.UploadsManager( 2153): End new media; added: 0, uploading: 0, time: 122 ms
D/MediaProvider( 2375): [resizeThumb] resizeThumb thumbnail bm.width 512, bm.height 512
D/PMS     (  840): releaseWL(bbddc38): PARTIAL_WAKE_LOCK  wake:com.google.android.gms/com.google.android.libraries.social.mediamonitor.MediaMonitorIntentService 0x1 null
D/SmartNS_Utility( 5356): usb_cable_connect = 1
I/RemoteViews( 1128): reapply : com.android.settings 1 36
D/SmartNS_Utility( 5356): usb_denied = 0
I/SmartNS_PSService( 5356): usb notificaiton:true
E/WifiStateMachine(  840): WiFiDisplay: getWifidisplayApEnabled=false
E/MediaScannerService( 2375): [onStartCommand] --- Should not be here, redirect request. ----
E/MediaScannerService( 2375): [handleMessage] --- Should not be here, ignore request. ----
D/MediaProvider( 2375): [getAlbumArtOutputUri] invalid thumb, album_id:110
D/SmartNS_Utility( 5356): usb_cable_connect = 1
D/SmartNS_Utility( 5356): usb_denied = 0
I/RemoteViews( 1128): reapply : com.android.settings 1 36
I/SmartNS_PSService( 5356): KeyGuard locked:falseKeyGuard is secured:false
D/SmartNS_PSService( 5356): USB Plugged, Set USBPlugged=  truePSenabled:false
I/SmartNS_PSService( 5356): triggerFromIPT_UI:false
W/ContextImpl( 5356): Calling a method in the system process without a qualified user: android.app.ContextImpl.sendBroadcast:1459 android.content.ContextWrapper.sendBroadcast:376 c
om.android.settings.PSService.onStartCommand:507 android.app.ActivityThread.handleServiceArgs:3072 android.app.ActivityThread.access$2100:144
D/SmartNS_PSService( 5356): PSEnabled = true
I/Xposed  ( 5465): -------------handleLoadPackage: com.htc.calendar
W/ResourcesManager( 5465): Asset path '/system/framework/android.test.runner.jar' does not exist or contains no resources.
I/art     (  840): Explicit concurrent mark sweep GC freed 20756(995KB) AllocSpace objects, 3(48KB) LOS objects, 33% free, 20MB/30MB, paused 1.922ms total 184.556ms
I/RemoteViews( 1128): reapply : com.android.settings 2 36
D/SmartNS_PSService( 5356): NDIS flow run...
D/SmartNS_Utility( 5356): usb_cable_connect = 1
D/SmartNS_Utility( 5356): usb_denied = 0
D/SmartNS_PSService( 5356): Set IP: 192.168.99.249
D/SmartNS_PSService( 5356): Set Mask: 255.255.255.0
D/SmartNS_PSService( 5356): Set Gateway: 192.168.99.26
D/SmartNS_PSService( 5356): Set DNS: 192.168.99.26
D/UsbDeviceManager(  840): [USBNET] bCheckSuppFunc: ipt_enable
D/UsbDeviceManager(  840): [USBNET] isFunctionEnabled: ipt_enable
D/UsbDeviceManager(  840): [USBNET] mUsbnetService.UsbMiscControl_IPT: 1
D/UsbnetService(  840): [USBNET] MiscControl_IPT: 1
D/NetworkManagementService(  840): [USBNET] setIptDhcp
D/NetworkManagementService(  840): [USBNET] Use temp dhcp range
I/Xposed  ( 5465): -------------handleInitPackageResources: com.htc.calendar
E/UsbnetService(  840): Exception of setIptDhcp
W/System.err(  840): java.lang.IllegalArgumentException: command '54 tether ipt set 192.168.99.26' failed with '500 54 Unknown tether cmd'
W/System.err(  840):    at com.android.server.NetworkManagementService.setIptDhcp(NetworkManagementService.java:1380)
W/System.err(  840):    at com.android.server.UsbnetService.setIptDhcp(UsbnetService.java:1253)
W/System.err(  840):    at com.android.server.UsbnetService.UsbMiscControl_IPT(UsbnetService.java:1113)
W/System.err(  840):    at com.android.server.usb.UsbDeviceManager.isFunctionEnabled(UsbDeviceManager.java:1971)
W/System.err(  840):    at com.android.server.usb.UsbService.isFunctionEnabled(UsbService.java:290)
W/System.err(  840):    at android.hardware.usb.IUsbManager$Stub.onTransact(IUsbManager.java:340)
W/System.err(  840):    at android.os.Binder.execTransact(Binder.java:454)
W/System.err(  840): Caused by: com.android.server.NativeDaemonConnector$NativeDaemonArgumentException: command '54 tether ipt set 192.168.99.26' failed with '500 54 Unknown tether
 cmd'
W/System.err(  840):    at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:421)
W/System.err(  840):    at com.android.server.NativeDaemonConnector.executeForList(NativeDaemonConnector.java:360)
W/System.err(  840):    at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:325)
W/System.err(  840):    at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:310)
W/System.err(  840):    at com.android.server.NetworkManagementService.setIptDhcp(NetworkManagementService.java:1378)
W/System.err(  840):    ... 6 more
D/UsbnetService(  840): [USBNET] MiscControl+: 1,usb_ipt
I/dnsmasq ( 5485): started, version 2.51 cachesize 150
I/dnsmasq ( 5485): compile time options: no-IPv6 GNU-getopt no-DBus no-I18N DHCP no-scripts no-TFTP
D/UsbDeviceManager(  840): setCurrentFunctions(ipton) default: false
W/dnsmasq ( 5485): warning: no upstream servers configured
D/UsbDeviceManager(  840): [USBNET] handleMessage: 2; mConnected=true, mConfiguration=true
I/dnsmasq ( 5485): DHCP, IP range 192.168.99.26 -- 192.168.99.26, lease time 1d
D/PMS     (  840): acquireWL(270fd04d): SCREEN_BRIGHT_WAKE_LOCK  ON_AFTER_RELEASE WindowManager 0x2000000a 840 1000 WorkSource{10207}
I/dnsmasq ( 5485): DHCP, IP range 192.168.43.2 -- 192.168.43.254, lease time 1h
D/UsbDeviceManager(  840): setEnabledFunctions(ipton; false; mAcmEnabled: false)
E/dnsmasq ( 5485): bad address at /etc/hosts line 2
D/UsbDeviceManager(  840): send Fake intent while setEnabledFunctions
E/dnsmasq ( 5485): bad address at /etc/hosts line 3
D/UsbDeviceManager(  840): sendStickyBroadcast: broadcasting Intent { act=android.hardware.usb.action.USB_STATE flg=0x20000000 (has extras) } connected: true configured: true; SetC
urrentFunctions= mass_storage,adb
E/dnsmasq ( 5485): bad address at /etc/hosts line 4
D/UsbDeviceManager(  840): [USBNET] check if ACM should be enabled
E/dnsmasq ( 5485): bad address at /etc/hosts line 5
D/UsbDeviceManager(  840): Re-send Fake intent due to no setUsbConfig
E/dnsmasq ( 5485): bad address at /etc/hosts line 6
D/UsbDeviceManager(  840): sendStickyBroadcast: broadcasting Intent { act=android.hardware.usb.action.USB_STATE flg=0x20000000 (has extras) } connected: true configured: true; SetC
urrentFunctions= ipton,mtp,adb
D/Tethering(  840): got USB_STATE change: usbConnected=true, mRndisEnabled=false, mUsbTetherRequested=false
D/UsbnetService(  840): BroadcastReceiver::onReceive+
D/UsbnetService(  840): onReceive ACTION_USB_STATE: true,false
D/Tethering(  840): got USB_STATE change: usbConnected=true, mRndisEnabled=false, mUsbTetherRequested=false
D/FindExtension( 5375): FindExtension: before mHardwareRenderer.initialize, mSurface.isValid() = true
I/Adreno-EGL( 5375): <qeglDrvAPI_eglInitialize:410>: EGL 1.4 QUALCOMM build: AU_LINUX_ANDROID_LA.AF.1.1_RB1.05.00.02.006.020 - CR771817 ()
I/Adreno-EGL( 5375): OpenGL ES Shader Compiler Version: E031.25.03.06
I/Adreno-EGL( 5375): Build Date: 03/04/15 Wed
I/Adreno-EGL( 5375): Local Branch:
I/Adreno-EGL( 5375): Remote Branch: refs/tags/AU_LINUX_ANDROID_LA.AF.1.1_RB1.05.00.02.006.020
I/Adreno-EGL( 5375): Local Patches: NONE
I/Adreno-EGL( 5375): Reconstruct Branch: NOTHING
E/MediaScannerServiceEx( 2375): [getStorageMaskIdFromPath] path is null
D/MediaScannerServiceEx( 2375): [ServiceHandler][handleMessage] , action: null, Id: 0, path: /storage/emulated/0
D/NetworkManagementService(  840): [USBNET] startIptMode 2

D:\>

@Falseclock
Copy link
Author

rebooted again to compare logs

D/SmartNS_Utility( 2736): usb_cable_connect = 1
D/SmartNS_Utility( 2736): usb_denied = 0
D/SmartNS_PSService( 2736): Set IP: 192.168.99.239
D/SmartNS_PSService( 2736): Set Mask: 255.255.255.0
D/SmartNS_PSService( 2736): Set Gateway: 192.168.99.70
D/SmartNS_PSService( 2736): Set DNS: 192.168.99.70
D/UsbDeviceManager(  833): [USBNET] bCheckSuppFunc: ipt_enable
D/UsbDeviceManager(  833): [USBNET] isFunctionEnabled: ipt_enable
D/UsbnetService(  833): [USBNET] MiscControl_IPT: 1
D/UsbDeviceManager(  833): [USBNET] mUsbnetService.UsbMiscControl_IPT: 1
D/NetworkManagementService(  833): [USBNET] setIptDhcp
D/NetworkManagementService(  833): [USBNET] Use temp dhcp range
E/UsbnetService(  833): Exception of setIptDhcp
W/System.err(  833): java.lang.IllegalArgumentException: command '55 tether ipt set 192.168.99.70' failed with '500 55 Unknown tether cmd'
W/System.err(  833):    at com.android.server.NetworkManagementService.setIptDhcp(NetworkManagementService.java:1380)
W/System.err(  833):    at com.android.server.UsbnetService.setIptDhcp(UsbnetService.java:1253)
W/System.err(  833):    at com.android.server.UsbnetService.UsbMiscControl_IPT(UsbnetService.java:1113)
W/System.err(  833):    at com.android.server.usb.UsbDeviceManager.isFunctionEnabled(UsbDeviceManager.java:1971)
W/System.err(  833):    at com.android.server.usb.UsbService.isFunctionEnabled(UsbService.java:290)
W/System.err(  833):    at android.hardware.usb.IUsbManager$Stub.onTransact(IUsbManager.java:340)
W/System.err(  833):    at android.os.Binder.execTransact(Binder.java:454)
W/System.err(  833): Caused by: com.android.server.NativeDaemonConnector$NativeDaemonArgumentException: command '55 tether ipt set 192.168.99.70' failed with '500 55 Unknown tether
 cmd'
W/System.err(  833):    at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:421)
W/System.err(  833):    at com.android.server.NativeDaemonConnector.executeForList(NativeDaemonConnector.java:360)
W/System.err(  833):    at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:325)
W/System.err(  833):    at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:310)
D/UsbDeviceManager(  833): setCurrentFunctions(ipton) default: false
W/System.err(  833):    at com.android.server.NetworkManagementService.setIptDhcp(NetworkManagementService.java:1378)
W/System.err(  833):    ... 6 more
D/UsbDeviceManager(  833): [USBNET] handleMessage: 2; mConnected=true, mConfiguration=true
D/UsbnetService(  833): [USBNET] MiscControl+: 1,usb_ipt
D/UsbDeviceManager(  833): setEnabledFunctions(ipton; false; mAcmEnabled: false)
D/UsbDeviceManager(  833): send Fake intent while setEnabledFunctions
D/NetworkManagementService(  833): [USBNET] startIptMode 2
I/art     ( 4556): Explicit concurrent mark sweep GC freed 4329(462KB) AllocSpace objects, 0(0B) LOS objects, 51% free, 1949KB/3MB, paused 457us total 84.816ms
D/UsbDeviceManager(  833): sendStickyBroadcast: broadcasting Intent { act=android.hardware.usb.action.USB_STATE flg=0x20000000 (has extras) } connected: true configured: true; SetC
urrentFunctions= mass_storage,adb
I/Xposed  ( 6155): -------------handleLoadPackage: eu.chainfire.supersu
I/dnsmasq ( 6181): started, version 2.51 cachesize 150
I/dnsmasq ( 6181): compile time options: no-IPv6 GNU-getopt no-DBus no-I18N DHCP no-scripts no-TFTP
W/dnsmasq ( 6181): warning: no upstream servers configured
I/dnsmasq ( 6181): DHCP, IP range 192.168.99.70 -- 192.168.99.70, lease time 1d
I/dnsmasq ( 6181): DHCP, IP range 192.168.43.2 -- 192.168.43.254, lease time 1h
E/dnsmasq ( 6181): bad address at /etc/hosts line 2
E/dnsmasq ( 6181): bad address at /etc/hosts line 3
E/dnsmasq ( 6181): bad address at /etc/hosts line 4
E/dnsmasq ( 6181): bad address at /etc/hosts line 5
E/dnsmasq ( 6181): bad address at /etc/hosts line 6

D:\>

@Falseclock
Copy link
Author

it is strange why I have 2 logcat processes after phone restart
and it seems xposed collecting logcat not from the process which does it

@Falseclock
Copy link
Author

The same happen not to me only. I asked my users provide log file and their log files shows errors only from initZygote.

@rovo89
Copy link
Owner

rovo89 commented Apr 9, 2015

Are those users on the same (or a similar) ROM? If so, maybe the logcat binary is indeed broken on that ROM. Could you send it to me so I can test this myself?

Maybe it would also be interesting to do the following:

adb shell logcat > log1.txt
<wait for logcat to end>
adb shell logcat -d > log2.txt

And then compare the logs to find out what happens around the crash. Maybe something is logged about why logcat ends.

@roberto-sartori-gl
Copy link

I've also a simliar problem: there is no log from the Xposed Installer application. The file /data/data/de.robv.android.xposed.installer/log/error.log is empty, like error.log.old (same directory). There aren't other files here. I'm running CM 12 on Galaxy S4, Xposed works great, without problems.
I've taken a logcat from adb with a pc, from phone start to an usable screen: https://drive.google.com/file/d/0B6sB57I4mu3XVHczUE9EaW9pazg/view?usp=sharing

@Falseclock
Copy link
Author

Changed phone and got the same problem. Previous was HTC One M7 Dual SIM,
Current is HTC One M8 Dual SIM and problem remains - no any errors in Xposed logfile

@Falseclock
Copy link
Author

the problem is following

adb does not show any device connected until boot complete broadcast happen.
once screen shows desktop, adb shows devices and logcat can be given from cmd after that.

D:\>adb shell
shell@htc_m8dug:/ $ ps|grep logcat
ps|grep logcat
root      553   550   1380   808   ffffffff 00000000 S logcat
root      762   456   1384   820   ffffffff 00000000 S logcat
root      769   762   29656  1652  ffffffff 00000000 S xposed_logcat
shell     3917  476   1384   812   c0287c54 b6f4e570 S logcat
shell@htc_m8dug:/ $

@kmark
Copy link

kmark commented May 5, 2015

I can reproduce this. CM12 nightly on a jfltevzw. The Xposed log will show the logcat output during boot (the Loading modules from... stuff) but after the boot no further output is added. XposedBridge.log continues to output to logcat though.

@kmark
Copy link

kmark commented May 5, 2015

Interestingly, and this may be related, the boot halts if I call XposedBridge.log in the initZygote callback.

Things seem to boot normally and the log works:

05-05 01:35:20.161    5992-5992/? I/Xposed﹕ Detected ART runtime
05-05 01:35:20.161    5992-5992/? I/Xposed﹕ Found Xposed class de/robv/android/xposed/XposedBridge, now initializing
05-05 01:35:20.171    6015-6015/? I/ServiceManager﹕ Waiting for service batterystats...
05-05 01:35:20.281    5992-5992/? I/Xposed﹕ Initializing XposedBridge version 64
05-05 01:35:20.361    6217-6217/? D/idmap﹕ error: no read access to /vendor/overlay: No such file or directory
05-05 01:35:20.381    5992-5992/? I/Xposed﹕ Loading modules from /data/app/com.versobit.kmark.xhangouts-1/base.apk
05-05 01:35:20.531    5992-5992/? I/Xposed﹕ Loading class com.versobit.kmark.xhangouts.XHangouts
05-05 01:35:20.571    5992-5992/? I/Xposed﹕ XHangouts: id -> uid=0(root) gid=0(root) context=u:r:zygote:s0

And the last message I get from Zygote is the "end preload." I get a few other driver-related messages afterwards but then everything just stops. The device does not reboot and the boot animation continues until the screen goes black but remains on.

@rovo89
Copy link
Owner

rovo89 commented May 5, 2015

@kmark Do you have the same issue that a manually started logcat stops? If yes, could you try this please? #34 (comment)

As for the halting boot: Do you by any chance start a thread in initZygote? That would prevent the system from booting...

@Falseclock
Copy link
Author

@rovo89 , it does not stop.

behavior is following.

  1. connecting USB cable to phone. adb shows devices. logcat can be given.
  2. restarting phone. when phone gone to black screen issuing adb logcat > log1.txt and waiting for device.
  3. phone boots, but adb still waiting.
  4. canceling adb and issuing adb devices - nothing shown
  5. reconnecting usb cable and issuing adb devices - device is visible.
  6. can give now logcat which shows nothing cause earlier log buffer is gone

the same if disconnect USB, restart phone and during boot plug usb - adb does not see any devices until boot complete broadcast is received and USB reconnected.

ps shows two automatically started logcat processes.

@kmark , please confirm if the same happens to you also.

@rovo89
Copy link
Owner

rovo89 commented May 5, 2015

Wait, you wrote:

you know, when android sends broadcast boot complete, i can issue adb logcat command, but after a couple of seconds command ends and I have to give adb logcat again.

Is this (still) the case or not?

It's normal that adb isn't available during early boot, but I don't see how that should be related to this issue. If the logcat command ends, that's not normal, and that's what I'd like to focus on for now.

@Falseclock
Copy link
Author

@rovo89 , yes.. that was for with HTC One M7 dual sim, Now I have HTC One M8 dual sim.

the main problem is that phone has two logcat processes started by the system and Xposed parses from earlier process while main garbage in the second one.

@Falseclock
Copy link
Author 

shell@htc_m8dug:/ $ ps |grep logcat
ps |grep logcat
root      557   544   1380   808   ffffffff 00000000 S logcat
root      755   457   1384   820   ffffffff 00000000 S logcat
root      759   755   29656  1652  ffffffff 00000000 S xposed_logcat
shell@htc_m8dug:/ $

@rovo89
Copy link
Owner

rovo89 commented May 5, 2015

yes.. that was for with HTC One M7 dual sim, Now I have HTC One M8 dual sim.

So? Your adb logcat command keeps running on the new phone and keeps displaying new log lines? Even after a few minutes of intensive usage?

the main problem is that phone has two logcat processes started by the system and Xposed parses from earlier process while main garbage in the second one.

Sorry, I don't understand what you're trying to say. How do you know which process Xposed parses from? And what's "main garbage"? The existence of two logcat processes doesn't necessarily mean anything.

@kmark
Copy link

kmark commented May 5, 2015

I do not have two logcat processes. I did a soft reboot to see if another would appear but it would not. The PIDs of both of the below did change suggesting they restarted properly.

USER  PID    PPID   NAME
root  13888  13858  logcat
root  13889  13888  xposed_logcat

logcat does not seem to crash either. adb shell logcat > log never returns even during a full soft reboot.

I did a quick check and XposedBridge.log does output to the Xposed log file during initZygote as normal. So everything seems to be working until the boot is complete at which point the Xposed log is no longer written to but continues to output to logcat.

@Falseclock:

  1. Yes.
  2. Assuming you mean a full reboot? Yes. adb returns - waiting for device -
  3. adb still has the - waiting for device - showing but it is now connected and capturing output. You just cannot see the log on the terminal because it is being redirected to the file.

If you don't do output redirection (the > log1.txt) you should get something like this on boot

Klingon:~ kmark$ adb logcat
- waiting for device -
(device starts to boot, next message does not appear for a few seconds at least)
--------- beginning of system
I/auditd  (  229): Starting up
--------- beginning of main
I/cm      (  221): ____ _   _ ____ _  _ ____ ____ ____ _  _ _  _ ____ ___ 
I/cm      (  253): |     \_/  |__| |\ | |  | | __ |___ |\ | |\/| |  | |  \ 
I/cm      (  256): |___   |   |  | | \| |__| |__] |___ | \| |  | |__| |__/ 
I/installd(  235): installd firing up
I/audit_log(  229): Previous audit logfile detected, rotating
E/audit_rules(  229): Could not read audit rules /data/misc/audit/audit.rules: No such file or directory
I/cm      (  261): Welcome to Android 5.0.2 / CyanogenMod-12-20150313-SKANK-jfltevzw 
I/        (  231): debuggerd: Feb 23 2015 19:06:34
I/kickstart-qcks(  228): PARAMETER VALUES

Depending on your ROM things will be different but it should be pretty obvious you're capturing the initial boot.

It sounds like, at least for you, adb isn't able to reconnect to your device unless you physically unplug the device from your computer? adb is able to reconnect just fine for me.

As for the halting boot: Do you by any chance start a thread in initZygote? That would prevent the system from booting...

That would be it, thanks.

@Falseclock
Copy link
Author

@rovo89

found this in kernel.log
applicable before renaming htc_ebdlogd

after renaming, no more entries in /devlog/kernel_log

05-07 23:51:53 <6>[    5.827965] c0    393 type=1400 audit(1431021113.333:7): avc: denied { read } for pid=455 comm="zygote" name="input" dev="tmpfs" ino=7238 scontext=u:r:zygote:s0 tcontext=u:object_r:input_device:s0 tclass=dir
05-07 23:51:53 <6>[    5.829247] c0    142 [USBDIAG] diagchar_ioctl:kworker/u:3(parent:kthreadd): tgid=142, iocmd=0, ioarg=-296667904
05-07 23:51:53 <6>[    5.829313] c0    142 [USBDIAG] diagchar_ioctl:kworker/u:3(parent:kthreadd): tgid=142, iocmd=0, ioarg=-296667904
05-07 23:51:53 <6>[    5.831083] c0    393 type=1400 audit(1431021113.333:8): avc: denied { syslog } for pid=764 comm="logcat" capability=34 scontext=u:r:untrusted_app:s0 tcontext=u:r:untrusted_app:s0 tclass=capability2
05-07 23:51:53 <6>[    5.831282] c0    393 type=1400 audit(1431021113.333:9): avc: denied { syslog } for pid=764 comm="logcat" capability=34 scontext=u:r:untrusted_app:s0 tcontext=u:r:untrusted_app:s0 tclass=capability2

@kmark
Copy link

kmark commented May 9, 2015

@rovo89

Thanks for the detailed answer. Just for clarification: Does the logcat that you start manually display the whole output, even after you do a soft reboot? Otherwise, it might just log more because it was started later.

Yes, I did not output to a file so I could watch the new data roll in.

@rovo89
Copy link
Owner

rovo89 commented May 9, 2015

OK, so maybe it's a problem caused by SELinux? Although the description for "syslog" is "Configure kernel syslog subsystem", and access to the log daemon is configured differently in the policy files... And it would also mean that HTC and any other affected ROM enables SELinux later.

@bgcngm
Copy link

bgcngm commented May 15, 2015

@flar2, could you please confirm if you have this kind of issue with M8?

@kmark
Copy link

kmark commented May 20, 2015

Just wanted to add that this bug, or at least my variant of it, continues into Android 5.1 (latest CM nightlies) and the most recent unofficial Xposed 5.1 Alpha 4 (20150514).

@arter97
Copy link
Contributor

arter97 commented Jun 1, 2015

Been doing some work about this since it's reproducible on every Samsung Touchwiz devices.
Something must be killing logcat binary. Modifying the code to run under "/system/bin/sh -c", or even putting it under nohup still results in short log, not updating log.

I think we should add some kinds of "respawn" code when logcat pipe dies.

@arter97
Copy link
Contributor

arter97 commented Jun 1, 2015

Update - No it's not dying. It's not elevated to root.
Wrapping the code to run under "/system/xbin/su -c" completely fixes the issue.

This should be enough info for fixing the issue, @rovo89.

@arter97
Copy link
Contributor

arter97 commented Jun 1, 2015

Here's the built binary and its source code, which I workarounded the issue.
Of course this should not be the correct way of fixing the issue.
Hopefully @rovo89 can come up with a better fix.

(If you are using SuperSU, you need to enable "Enable su on boot" option)

http://arter97.com/browse/Xposed/etc/tmp/

@rovo89
Copy link
Owner

rovo89 commented Jun 1, 2015

I'm pretty sure that the daemon is executed as root. The output of ps confirms this. If executing is via su is working, then it might be indeed related to SELinux. Do you see any denials in logcat, like the ones posted above?

I would like to avoid the uncertainty of the various su versions, dependency on their configuration etc....

@arter97
Copy link
Contributor

arter97 commented Jun 1, 2015

This is running on my custom kernel, which has SELinux force set to permissive.

So it's not "denied". Maybe some source parts of logging functionality checks for some context and if its valid..?

The output of not patched Xposed log seems very similar to what we can get from '$ logcat' in a ordinary, non-root terminal app.

Or we can go ask Chainfire for some help.. :)

@bgcngm
Copy link

bgcngm commented Jun 1, 2015

Actually I tried your binary and have the same problem.

@wanam
Copy link

wanam commented Jun 1, 2015

I didn't try his binary, but my built binary with his solution is working great on my GNote4.

@rovo89
Copy link
Owner

rovo89 commented Jun 7, 2015

@arter97 Could you please try it without xposed::dropCapabilities(); instead of the detour through su? If that works, everything but the CAP_SYSLOG capability should be dropped (an optional parameter for this already exists):
https://github.com/arter97/android_kernel_samsung_smdk4412/blob/lollipop-release/drivers/staging/android/logger.c#L525

@arter97
Copy link
Contributor

arter97 commented Jun 7, 2015

Mmmm will try soon.

On Sun, Jun 7, 2015 at 6:05 PM, rovo89 notifications@github.com wrote:

@arter97 https://github.com/arter97 Could you please try it without
xposed::dropCapabilities(); instead of the detour through su? If that
works, everything but the CAP_SYSLOG capability should be dropped (an
optional parameter for this already exists):

https://github.com/arter97/android_kernel_samsung_smdk4412/blob/lollipop-release/drivers/staging/android/logger.c#L525

—
Reply to this email directly or view it on GitHub
#34 (comment).

@rovo89
Copy link
Owner

rovo89 commented Jun 7, 2015

Additionally (?), it could help to change the group ID of the process to AID_LOG (1007) before dropping the capabilities. That what /dev/log/main belongs to, and as far as I understand, the group will always have access. Capabilities might be blocked by SELinux, but setgid is a capability that will always be necessary for the Zygote process.

@wanam
Copy link

wanam commented Jun 7, 2015

It doesn't seem to log on both cases:

  • Without the "xposed::dropCapabilities()"
  • With xposed::dropCapabilities(CAP_SYSLOG) //34

But changing the group ID to AID_LOG with xposed::dropCapabilities(CAP_SYSLOG) seems to work fine.
Here is my changed "xposed_logcat.cpp": http://pastebin.com/Bj3Ksywy

@rovo89
Copy link
Owner

rovo89 commented Jun 7, 2015

Thanks. After quite some research, I found out that capabilities are not kept after execl() by default. Besides that, my dropCapabilities() function didn't work correctly with newer capabilities.

Could you try if my patch works as well? And if it works fine even without changing the group ID?

@wanam
Copy link

wanam commented Jun 7, 2015

Thanks, your patch is working fine on my Note4.

@Falseclock
Copy link
Author

Can anybody give binaries to test?

@wanam
Copy link

wanam commented Jun 7, 2015

@Falseclock https://www.dropbox.com/s/0rg8vbfxwa5c4li/app_process32_xposed?dl=0

@Falseclock
Copy link
Author

@wanam , Thanks. replaced, but phone won't boot anymore

logcat is here
https://drive.google.com/file/d/0B2lAfZOYZcTxMkI3Ny1qNXNmN2c/view?usp=sharing

@Falseclock
Copy link
Author

got it working.
Installed alpha 4 and then replaced binary.

@rovo89
Copy link
Owner

rovo89 commented Jun 7, 2015

And? Is it fixed for you?

Btw, build instructions and scripts are here: https://github.com/rovo89/XposedTools

@Falseclock
Copy link
Author

@rovo89 , looks yes. A lot of garbage in logfile now ))

need to double check before confirming.
trying now to fix errors

@Falseclock
Copy link
Author

@rovo89 , thanks!!!! It is working now! Shall I close issue or you will do it?

@rovo89 rovo89 closed this as completed in ca2ddf3 Jun 7, 2015
@rovo89
Copy link
Owner

rovo89 commented Jun 7, 2015

I closed it by merging the commit into the master branch. ;)

@wanam wanam mentioned this issue Nov 30, 2015
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@wanam @kmark @rovo89 @bgcngm @Falseclock @arter97 @roberto-sartori-gl